Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Use prefix in all vtorc check and recover logs (#17526) #592

Merged
merged 3 commits into from
Jan 24, 2025
Merged

Use prefix in all vtorc check and recover logs (#17526) #592

merged 3 commits into from
Jan 24, 2025

Conversation

ejortegau
Copy link
Collaborator

This is a backport of vitessio#17526 . Original PR description below:

Description

This is meant to make recovery actions more easily identified from the logs. See vitessio#17465

Some examples of recoveries, when running the local example cluster:

Initial recovery for cluster with no primary 
I0117 11:19:11.970564  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Starting checkAndRecover
I0117 11:19:11.970622  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with ClusterHasNoPrimary detection on zone1-0000000100; isActionable?: true
I0117 11:19:11.984405  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: Proceeding with ClusterHasNoPrimary recovery on zone1-0000000100 validation after acquiring shard lock.
I0117 11:19:11.985613  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Force refreshing all shard tablets
I0117 11:19:12.002617  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with recovery on zone1-0000000100; isRecoverable?: true
I0117 11:19:12.002932  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: Analysis: ClusterHasNoPrimary, will elect a new primary for commerce:0
W0117 11:19:12.014369  231305 log.go:153] Recovery for ClusterHasNoPrimary on commerce/0: PRS - no replication statue from zone1-0000000101, using empty gtid set
W0117 11:19:12.014626  231305 log.go:153] Recovery for ClusterHasNoPrimary on commerce/0: PRS - no replication statue from zone1-0000000100, using empty gtid set
I0117 11:19:12.970190  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Starting checkAndRecover
I0117 11:19:12.970230  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with ClusterHasNoPrimary detection on zone1-0000000100; isActionable?: true
E0117 11:19:12.971729  231305 log.go:168] Recovery for ClusterHasNoPrimary on commerce/0: Failed to lock shard, aborting recovery: node already exists: lock already exists at path keyspaces/commerce/shards/0
I0117 11:19:13.004532  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Recovery succeeded
I0117 11:19:13.005549  231305 log.go:138] Recovery for ClusterHasNoPrimary on commerce/0: Topology recovery: {"ID":1,"AnalysisEntry":{"AnalyzedInstanceAlias":"zone1-0000000100","AnalyzedInstancePrimaryAlias":"\u003cnil\u003e","TabletType":2,"PrimaryTimeStamp":"0001-01-01T00:00:00Z","ClusterDetails":{"Keyspace":"commerce","Shard":"0"},"AnalyzedKeyspace":"commerce","AnalyzedShard":"0","ShardPrimaryTermTimestamp":"","AnalyzedInstanceBinlogCoordinates":{"LogFile":"vt-0000000100-bin.000001","LogPos":157,"Type":0},"IsPrimary":true,"IsClusterPrimary":false,"LastCheckValid":true,"LastCheckPartialSuccess":true,"CountReplicas":0,"CountValidReplicas":0,"CountValidReplicatingReplicas":0,"ReplicationStopped":true,"ErrantGTID":"","ReplicaNetTimeout":0,"HeartbeatInterval":0,"Analysis":"ClusterHasNoPrimary","Description":"Cluster has no primary","StructureAnalysis":["NoWriteablePrimaryStructureWarning"],"OracleGTIDImmediateTopology":false,"BinlogServerImmediateTopology":false,"SemiSyncPrimaryEnabled":false,"SemiSyncPrimaryStatus":false,"SemiSyncPrimaryWaitForReplicaCount":1,"SemiSyncPrimaryClients":0,"SemiSyncReplicaEnabled":false,"CountSemiSyncReplicasEnabled":0,"CountLoggingReplicas":0,"CountStatementBasedLoggingReplicas":0,"CountMixedBasedLoggingReplicas":0,"CountRowBasedLoggingReplicas":0,"CountDistinctMajorVersionsLoggingReplicas":0,"CountDelayedReplicas":0,"CountLaggingReplicas":0,"IsActionableRecovery":true,"RecoveryId":1,"GTIDMode":"ON","MinReplicaGTIDMode":"","MaxReplicaGTIDMode":"","MaxReplicaGTIDErrant":"","IsReadOnly":true},"SuccessorAlias":"zone1-0000000100","IsSuccessful":true,"AllErrors":[],"RecoveryStartTimestamp":"","RecoveryEndTimestamp":"","DetectionID":0}
I0117 11:19:13.005686  231305 log.go:133] Recovery for ClusterHasNoPrimary on commerce/0: Forcing refresh of all tablets post recovery
Recovering from a stopped MySQL in primary tablet 
I0117 11:20:44.971064  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Starting checkAndRecover
I0117 11:20:44.971142  231305 log.go:138] Recovery for DeadPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with DeadPrimary detection on zone1-0000000100; isActionable?: true
I0117 11:20:44.983679  231305 log.go:138] Recovery for DeadPrimary on commerce/0: executeCheckAndRecoverFunction: Proceeding with DeadPrimary recovery on zone1-0000000100 validation after acquiring shard lock.
I0117 11:20:44.984512  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Force refreshing all shard tablets
I0117 11:20:44.996572  231305 log.go:138] Recovery for DeadPrimary on commerce/0: executeCheckAndRecoverFunction: proceeding with recovery on zone1-0000000100; isRecoverable?: true
I0117 11:20:44.996823  231305 log.go:138] Recovery for DeadPrimary on commerce/0: Analysis: DeadPrimary, RecoverDeadPrimary zone1-0000000100
I0117 11:20:44.997167  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - will initiate emergency reparent shard in keyspace - commerce, shard - 0
I0117 11:20:44.997934  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - Getting a new durability policy for semi_sync
I0117 11:20:45.000444  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - getting replication position from zone1-0000000101
I0117 11:20:45.000465  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - getting replication position from zone1-0000000102
I0117 11:20:45.000463  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - getting replication position from zone1-0000000100
W0117 11:20:45.002324  231305 log.go:153] Recovery for DeadPrimary on commerce/0: ERS - failed to get replication status from zone1-0000000100: rpc error: code = Unknown desc = TabletManager.StopReplicationAndGetStatus on zone1-0000000100: before status failed: net.Dial(/home/eduardo.ortega/vitess_sandbox/v22-dev/examples/local/vtdataroot/vt_0000000100/mysql.sock) to local server failed: dial unix /home/eduardo.ortega/vitess_sandbox/v22-dev/examples/local/vtdataroot/vt_0000000100/mysql.sock: connect: no such file or directory (errno 2002) (sqlstate HY000)
I0117 11:20:45.006592  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - started finding the intermediate source
I0117 11:20:45.006785  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - finding intermediate source - sorted replica: cell:"zone1"  uid:102
I0117 11:20:45.006887  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - finding intermediate source - sorted replica: cell:"zone1"  uid:101
I0117 11:20:45.006991  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - intermediate source selected - cell:"zone1"  uid:102
I0117 11:20:45.007065  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - found better candidate - cell:"zone1"  uid:102
I0117 11:20:45.007129  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - intermediate source is ideal candidate- true
I0117 11:20:45.007516  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - starting promotion for the new primary - zone1-0000000102
I0117 11:20:45.007552  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - setting new primary on replica zone1-0000000100
I0117 11:20:45.007560  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - setting new primary on replica zone1-0000000101
I0117 11:20:45.074764  231305 log.go:138] Recovery for DeadPrimary on commerce/0: ERS - populating reparent journal on new primary zone1-0000000102
I0117 11:20:45.080035  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Recovery succeeded
I0117 11:20:45.080105  231305 log.go:138] Recovery for DeadPrimary on commerce/0: Topology recovery: {"ID":6,"AnalysisEntry":{"AnalyzedInstanceAlias":"zone1-0000000100","AnalyzedInstancePrimaryAlias":"\u003cnil\u003e","TabletType":1,"PrimaryTimeStamp":"0001-01-01T00:00:00Z","ClusterDetails":{"Keyspace":"commerce","Shard":"0"},"AnalyzedKeyspace":"commerce","AnalyzedShard":"0","ShardPrimaryTermTimestamp":"2025-01-17 10:19:12.022420359 +0000 UTC","AnalyzedInstanceBinlogCoordinates":{"LogFile":"vt-0000000100-bin.000001","LogPos":18489,"Type":0},"IsPrimary":true,"IsClusterPrimary":true,"LastCheckValid":false,"LastCheckPartialSuccess":false,"CountReplicas":2,"CountValidReplicas":2,"CountValidReplicatingReplicas":0,"ReplicationStopped":true,"ErrantGTID":"","ReplicaNetTimeout":0,"HeartbeatInterval":0,"Analysis":"DeadPrimary","Description":"Primary cannot be reached by vtorc and none of its replicas is replicating","StructureAnalysis":null,"OracleGTIDImmediateTopology":true,"BinlogServerImmediateTopology":false,"SemiSyncPrimaryEnabled":true,"SemiSyncPrimaryStatus":true,"SemiSyncPrimaryWaitForReplicaCount":1,"SemiSyncPrimaryClients":2,"SemiSyncReplicaEnabled":true,"CountSemiSyncReplicasEnabled":2,"CountLoggingReplicas":2,"CountStatementBasedLoggingReplicas":0,"CountMixedBasedLoggingReplicas":0,"CountRowBasedLoggingReplicas":2,"CountDistinctMajorVersionsLoggingReplicas":1,"CountDelayedReplicas":0,"CountLaggingReplicas":0,"IsActionableRecovery":true,"RecoveryId":19,"GTIDMode":"ON","MinReplicaGTIDMode":"ON","MaxReplicaGTIDMode":"ON","MaxReplicaGTIDErrant":"","IsReadOnly":false},"SuccessorAlias":"zone1-0000000102","IsSuccessful":true,"AllErrors":[],"RecoveryStartTimestamp":"","RecoveryEndTimestamp":"","DetectionID":0}
I0117 11:20:45.080127  231305 log.go:133] Recovery for DeadPrimary on commerce/0: Forcing refresh of all tablets post recovery

Related Issue(s)

vitessio#17465

Checklist

  • "Backport to:" labels have been added if this change should be back-ported to release branches
  • If this change is to be back-ported to previous releases, a justification is included in the PR description
  • Tests were added or are not required
  • Did the new or modified tests pass consistently locally and on CI?
  • Documentation was added or is not required

Deployment Notes

n/a

@github-actions github-actions bot added this to the v19.0.7 milestone Jan 23, 2025
@ejortegau ejortegau marked this pull request as ready for review January 23, 2025 14:59
@ejortegau ejortegau requested a review from a team as a code owner January 23, 2025 14:59
@ejortegau ejortegau merged commit d2d0c36 into slack-19.0 Jan 24, 2025
163 of 165 checks passed
@ejortegau ejortegau deleted the backport-17526 branch January 24, 2025 14:10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@timvaillancourt timvaillancourt timvaillancourt approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
v19.0.7
Development

Successfully merging this pull request may close these issues.
2 participants
@ejortegau @timvaillancourt